feat: wrap provider.chat in llm.call span with timing and tokens#262
Merged
Conversation
…tokens Without per-call attribution there was no way to tell whether a slow agent loop was burning time inside provider.chat (network/LLM) or between calls (tool dispatch, queue waits). Token spend was visible only on the session log, not in Tempo traces. Open one `llm.call` span per retry attempt around `provider.chat`. After the call returns, record duration_ms plus the four token-usage counters and stop_reason as span attributes; on error, record the formatted error. Each retry gets its own span so a 429 backoff does not inflate the duration attributed to the eventual successful call. The span also carries `task.id`, `llm.model`, `llm.attempt`, and the request shape (tool/message counts) so Tempo queries can isolate slow calls without joining other spans. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
l50
changed the title
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #262 +/- ##
=======================================
Coverage 75.10% 75.11%
=======================================
Files 383 383
Lines 81465 81492 +27
=======================================
+ Hits 61187 61214 +27
Misses 20278 20278 ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
l50
added a commit
that referenced
this pull request
May 9, 2026
**Key Changes:**
- Wrapped each `provider.chat()` call inside `call_with_retry` in its
own `llm.call` info span so timing and token usage are attributed to the
attempt that produced them
- Captured per-attempt input, output, and cache token counts, duration,
stop reason, and error message as span fields
- Recorded `task.id`, `llm.model`, `llm.attempt`, `llm.tool_count`, and
`llm.message_count` at span creation for filterable Tempo queries
**Added:**
- Per-attempt `llm.call` `info_span!` in
`ares-llm/src/agent_loop/retry.rs` with `Empty` placeholders for fields
that are only known after the call returns (`llm.input_tokens`,
`llm.output_tokens`, `llm.cache_read_tokens`,
`llm.cache_creation_tokens`, `llm.duration_ms`, `llm.stop_reason`,
`llm.error`)
- Wall-clock duration measurement via `std::time::Instant` recorded into
`llm.duration_ms` so retry waits are not folded into the successful
call's latency
- `tracing::Instrument` instrumentation of the `provider.chat()` future
so async work runs inside the span context
**Changed:**
- `ares-llm/src/agent_loop/retry.rs` `use` line now imports
`std::time::Instant` plus `tracing::{field::Empty, info_span,
Instrument}` alongside the existing `warn`
- Result handling in `call_with_retry` was split: the call result is
first inspected to record token usage / stop reason / error on the span,
then the existing retry decision logic runs on that same result
l50
added a commit
that referenced
this pull request
May 9, 2026
**Key Changes:**
- Wrapped each `provider.chat()` call inside `call_with_retry` in its
own `llm.call` info span so timing and token usage are attributed to the
attempt that produced them
- Captured per-attempt input, output, and cache token counts, duration,
stop reason, and error message as span fields
- Recorded `task.id`, `llm.model`, `llm.attempt`, `llm.tool_count`, and
`llm.message_count` at span creation for filterable Tempo queries
**Added:**
- Per-attempt `llm.call` `info_span!` in
`ares-llm/src/agent_loop/retry.rs` with `Empty` placeholders for fields
that are only known after the call returns (`llm.input_tokens`,
`llm.output_tokens`, `llm.cache_read_tokens`,
`llm.cache_creation_tokens`, `llm.duration_ms`, `llm.stop_reason`,
`llm.error`)
- Wall-clock duration measurement via `std::time::Instant` recorded into
`llm.duration_ms` so retry waits are not folded into the successful
call's latency
- `tracing::Instrument` instrumentation of the `provider.chat()` future
so async work runs inside the span context
**Changed:**
- `ares-llm/src/agent_loop/retry.rs` `use` line now imports
`std::time::Instant` plus `tracing::{field::Empty, info_span,
Instrument}` alongside the existing `warn`
- Result handling in `call_with_retry` was split: the call result is
first inspected to record token usage / stop reason / error on the span,
then the existing retry decision logic runs on that same result
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Key Changes:
provider.chat()call insidecall_with_retryin its ownllm.callinfo span so timing and token usage are attributed to the attempt that produced themtask.id,llm.model,llm.attempt,llm.tool_count, andllm.message_countat span creation for filterable Tempo queriesAdded:
llm.callinfo_span!inares-llm/src/agent_loop/retry.rswithEmptyplaceholders for fields that are only known after the call returns (llm.input_tokens,llm.output_tokens,llm.cache_read_tokens,llm.cache_creation_tokens,llm.duration_ms,llm.stop_reason,llm.error)std::time::Instantrecorded intollm.duration_msso retry waits are not folded into the successful call's latencytracing::Instrumentinstrumentation of theprovider.chat()future so async work runs inside the span contextChanged:
ares-llm/src/agent_loop/retry.rsuseline now importsstd::time::Instantplustracing::{field::Empty, info_span, Instrument}alongside the existingwarncall_with_retrywas split: the call result is first inspected to record token usage / stop reason / error on the span, then the existing retry decision logic runs on that same result